Kerry Osborne's Oracle Blog

I posted earlier on Explain Plan’s tendency to spread rumors (Explain Plan Lies). Autotrace is another commonly used tool that suffers from the same basic character flaw (i.e. it lies too). The reason is simple. It uses the Explain Plan command under the covers.

Here’s a quick demonstration:

> sqlplus "/ as sysdba"

SQL*Plus: Release 11.2.0.1.0 Production on Mon Feb 15 11:51:27 2010

Copyright (c) 1982, 2009, Oracle.  All rights reserved.


Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

SYS@LAB112> @flush_pool

System altered.

SYS@LAB112> @avgskew_X
SYS@LAB112> var X varchar2(2);
SYS@LAB112> exec :X := 'N';

PL/SQL procedure successfully completed.

SYS@LAB112> -- should cause index access due to histogram on col4
SYS@LAB112> 
SYS@LAB112> set autotrace on
SYS@LAB112> select /* test autotrace */ avg(pk_col) from kso.skew a where col4 = :X
  2  /

 AVG(PK_COL)
------------
961866206.84

1 row selected.


Execution Plan
----------------------------------------------------------
Plan hash value: 568322376

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |     1 |    24 | 28420   (2)| 00:05:42 |
|   1 |  SORT AGGREGATE    |      |     1 |    24 |            |          |
|*  2 |   TABLE ACCESS FULL| SKEW |    10M|   244M| 28420   (2)| 00:05:42 |
---------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - filter("COL4"=:X)


Statistics
----------------------------------------------------------
        737  recursive calls
          0  db block gets
        250  consistent gets
          0  physical reads
          0  redo size
        444  bytes sent via SQL*Net to client
        420  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          7  sorts (memory)
          0  sorts (disk)
          1  rows processed

SYS@LAB112> 
SYS@LAB112> set autotrace off
SYS@LAB112> 
SYS@LAB112> select sql_id, child_number, sql_text from v$sql where sql_text like '%test autotrace%'
  2  /

SQL_ID        CHILD_NUMBER
------------- ------------
SQL_TEXT
-----------------------------------------------------------------------------------------------------------------------------------------------------------
9hv3fa42xhcm1            0
EXPLAIN PLAN SET STATEMENT_ID='PLUS4294967295' FOR select /* test autotrace */ avg(pk_col) from kso.skew a where col4 = :X

68zbpw01f4gh5            0
select sql_id, child_number, sql_text from v$sql where sql_text like '%test autotrace%'

2h0ajqmn8zgww            0
select /* test autotrace */ avg(pk_col) from kso.skew a where col4 = :X


3 rows selected.

SYS@LAB112> 
SYS@LAB112> select * from table(dbms_xplan.display_cursor('2h0ajqmn8zgww','','typical'))
  2  /

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  2h0ajqmn8zgww, child number 0
-------------------------------------
select /* test autotrace */ avg(pk_col) from kso.skew a where col4 = :X

Plan hash value: 1946853647

------------------------------------------------------------------------------------------
| Id  | Operation                    | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |           |       |       |    25 (100)|          |
|   1 |  SORT AGGREGATE              |           |     1 |    24 |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID| SKEW      |  3170 | 76080 |    25   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | SKEW_COL4 |  3170 |       |     8   (0)| 00:00:01 |
------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - access("COL4"=:X)


20 rows selected.

So I flushed the shared pool, executed my statement, and autotrace says it did a full table scan on my Skew table. But it completed in less than a second – so I doubt that’s true. Note also that autotrace says I only did 250 lio’s (the table actually has over 150K blocks).

Next we looked in v$sql for any statements that contained the string “test autotrace”. We found 3 statements:

1. the current statement doing the lookup in v$sql (68zbpw01f4gh5)
2. the actual statement that we were looking for (2h0ajqmn8zgww)
3. and an Explain Plan statement (9hv3fa42xhcm1)

Finally, we looked at the plan that statement 2h0ajqmn8zgww had actually used with dbms_xplan.display_cursor. It shows that the statement actually did an Index Range Scan, not a Full Table Scan.

By the way, this example is on 11gR2, but it behaves the same way in 10g.

So there you have it. Autotrace lies too! (at least it can, on the plan part of the output, due to it’s reliance on the Explain Plan command)

Update: I just ran across this post by Tom Kyte that precedes mine by about 3 years. Better later than never I guess.